Columbia Kermit/kermit.zip/newsgroups/misc.20041116-20060924/[e-mail]_Tue Apr 25 12:16:12 2006.msg

Internet Message Format | 2020-01-01 | 5KB

Path: newsmaster.cc.columbia.edu!newsfeed.nyu.edu!news.maxwell.syr.edu!newsfeed.icl.net!newsfeed.fjserv.net!oleane.net!oleane!news.in2p3.fr!in2p3.fr!proxad.net!216.239.36.134.MISMATCH!postnews.google.com!z34g2000cwc.googlegroups.com!not-for-mail
From: "tomviolin" <[e-mail]>
Newsgroups: comp.protocols.kermit.misc
Subject: Re: speed of script execution
Date: 21 Apr 2006 16:22:35 -0700
Organization: http://groups.google.com
Lines: 120
Message-ID: <[e-mail]>
References: <[e-mail]>
   <[e-mail]>
NNTP-Posting-Host: 129.89.149.237
Mime-Version: 1.0
Content-Type: text/plain; charset="iso-8859-1"
X-Trace: posting.google.com 1145661762 19541 127.0.0.1 (21 Apr 2006 23:22:42 GMT)
X-Complaints-To: [e-mail]
NNTP-Posting-Date: Fri, 21 Apr 2006 23:22:42 +0000 (UTC)
User-Agent: G2/0.2
X-HTTP-UserAgent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.0.2) Gecko/20060308 Firefox/1.5.0.2,gzip(gfe),gzip(gfe)
Complaints-To: [e-mail]
Injection-Info: z34g2000cwc.googlegroups.com; posting-host=129.89.149.237;
   posting-account=ornCOQwAAAAyCG4a7NOAj_SMr54FiqNu
Xref: newsmaster.cc.columbia.edu comp.protocols.kermit.misc:15572

Frank da Cruz wrote:
> On 2006-04-20, tomviolin <[e-mail]> wrote:
> : Can anyone tell me why there is such a huge time discrepency between
> : the execution of the following scripts.  The only difference is the
> : curly braces.  I'm running on an ARM SBC from a flash drive, if that
> : makes any difference.
> :
> : ---- testx.ksc ----
> : #!/usr/bin/kermit +
> : {  assign \%p 1, set line  /dev/ttyAM\%p }
> : { close }
> : exit
> :
> : ---- testy.ksc ----
> : #!/usr/bin/kermit +
> : assign \%p 1, set line  /dev/ttyAM\%p
> : close
> : exit
> :
> : -- test results --
> : $ time ./testx.ksc
> : real    0m 0.60s
> : user    0m 0.04s
> : sys     0m 0.06s
> :
> : $ time ./testy.ksc
> : real    0m 0.09s
> : user    0m 0.05s
> : sys     0m 0.04s
> :
> :
> As in C, the braces mark a block, entry to and exit from which carries some
> setup and takedown cost.  When you have only one or two statements in the
> block, that cost is a lot higher, proportionally, than if you have a lot of
> statements in it.
>
[ stuff skipped ]
>
> If you have encountered a serious bottleneck in a real application, let me
> know, maybe something can be done about it.
>
> - Frank

I have played a bit with my examples as well as my larger system, and
have generated the following two examples, changed only with addition
of a couple of echo statements:

-- testx.ksc --
#!/usr/bin/kermit +
{  assign \%p 1, set line  /dev/ttyAM\%p }
echo test 1
{ close }
echo test 2
exit

-- testy.ksc --
#!/usr/bin/kermit +
assign \%p 1, set line  /dev/ttyAM\%p
echo test 1
close
echo test 2
exit

Again, testy.ksc runs much faster.  However, I am observing that, with
the slower testx.ksc script, that "test 1" appears almost instantly,
and that the vast majority of the 0.6 seconds is spent between "test 1"
and "test 2" appearing, with "test 2" appearing right before the
program ends.

Then, I further modified testx.ksc as follows:

--- testx1.ksc ---
#!/usr/bin/kermit +
{  assign \%p 1, set line  /dev/ttyAM\%p }
echo test 1
{ echo test 1a, close, echo test 1b  }
echo test 2
exit

Now of course the output is:

$ ./testx1.ksc
test 1
test 1a
test 1b
test 2

and the vast majority of the pause is between the appearance of "test
1a" and "test 1b", thus demonstrating that the "close" statement is the
cause of the problem.

PLUS, look at the "time" output again (results very similar to the
prior examples):

$ time ./testx.ksc
test 1
test 2
real    0m 0.63s
user    0m 0.05s
sys     0m 0.07s

$ time ./testy.ksc
test 1
test 2
real    0m 0.09s
user    0m 0.04s
sys     0m 0.05s

Notice that the "user" and "sys" times for testx.ksc and testy.ksc are
comparable and that for testy.ksc, the sum of "user" and "sys" are
close to (or apparently exactly) the value for "real".  However, the
"real" time for testx.ksc is way off the chart compared to the sum of
"user" and "sys" thus seeming to indicate that kermit is sleeping,
waiting for I/O, or otherwise in some sort of suspended state for about
0.51s.  Doesn't seem like time spent in setup or takedown of data
structures to me.

It would appear that the "close" statement is the culprit.  Why?  And
why does it delay only for testx.ksc and not testy.ksc?